Wrote a RD, but having issues with rendering form (spoly input). Isn't currently connected to any data.
Added a container to the prototype.
Writing up SDC3a notes on confluence.
Scraped FTS data for transfer period for presenting.
Transfer completed.
Looked at DaCHS quickstart in docker, got that up and running.
FTS transfers are starting to complete as the throughput increased to ~1.4MB/s per stream at points overnight.
Mihai has decreased max number of incoming/outgoing streams to 50 for srcdev.skatelescope.org. Also confirmed that the bugs noted from yesterday are entirely possible.
Completed notes up to Quick Start in DaCHS. Still need to do chapter on ObsCore implementation.
Started condensing DaCHS into a cheatsheet.
23rd ~ 09:45: Looks like the access token that the admin client uses to do transfers is timing out (lifetime 3600s) for the largest (5G) files when it finishes the transfer and comes to compute the destination checksum:
INFO Mon, 23 Jan 2023 09:36:09 +0100; Transfer accepted
INFO Mon, 23 Jan 2023 10:42:58 +0100; [1674466978155] BOTH http_plugin TRANSFER:EXIT davs://srcdev.skatelescope.org:443/storm/sa/test_rse/dev/deterministic/sdc3a/b2/39/sdc3a.MS.0.ZW2_IFRQ_0750.ms.table.f2_TSM0 => davs://spsrc14.iaa.csic.es:18027/disk/dev/deterministic/sdc3a/b2/39/sdc3a.MS.0.ZW2_IFRQ_0750.ms.table.f2_TSM0
INFO Mon, 23 Jan 2023 10:42:58 +0100; [1674466978155] DEST http_plugin CHECKSUM:ENTER
ERR Mon, 23 Jan 2023 10:42:58 +0100; Non recoverable error: [13] DESTINATION CHECKSUM HTTP 401 : Authentication ErrorIncreased the ska-rucio-admin client access token lifetime to 1day.
Would expect transfers to start succeeded in a couple of hours after new transfers using this access token with increased lifetime are finished. Current state (642 stuck):
sdc3a:sdc3a.MS.0 STUCK[72339/106/536] SPSRC_STORM 1 Aside: looks like the pipe is ~100M/s. FTS allows 100 concurrent streams, so each transfer goes ~1M/s. Looks like some of these larger files transferred for previous channels of the measurement set, so presumably at some point a single pipe was capable of >1M/s.
23rd ~ 12:50: Noticed that submitter-finisher isn’t making anymore submissions. This is because there are 88 locks in REPLICATING state, but the retry_count for these locks (in requests table) is == 3, which is the maximum it can have (finisher logs show EXCEEDED SUBMITTING DID sdc3a:sdc3a.MS.0.ZW2_IFRQ_0127.ms.table.f2_TSM0 REQUEST cc4e4bb34bb343bd8918954866415ac5 in state RequestState.FAILED). I think these are later marked as STUCK by some other process and the judge-repairer comes along later and retries them.
judge-repairer is currently finding the other STUCK locks, but previous entries show this takes ~4h:
2023-01-23 03:34:27,081 root 1 DEBUG Finished resetting counters for rule 6a52a7b156be4deba039f656a1ea80ea [72333/350/298]
2023-01-23 07:24:01,257 root 1 DEBUG Finding and repairing stuck locks for rule 6a52a7b156be4deba039f656a1ea80ea [72333/350/298]And it only started at 10:44:
2023-01-23 10:44:33,638 root 1 DEBUG Finished resetting counters for rule 6a52a7b156be4deba039f656a1ea80ea [72339/88/554]tl;dr we have a mixture of locks that have maxed out retries or are STUCK waiting for judge-repairer to allow them to reattempt (~2pm)
23rd ~ 16:00: Now getting authentication errors at the start of the transfer.
After a lot of digging around:
%fullRequest to “<pattern>%a %fullRequest %localPort "%reqAttribute{storm.remoteUser}" %date{"yyyy-MM-dd'T'HH:mm:ss.SSSXXX", UTC} "%reqAttribute{storm.requestId}" "%m %U %H" %s %b %D</pattern>” in /etc/storm/webdav/logback-access.xml on the storm-webdav machine to get the request token being used to authenticateexport FILE=uuidgen&& echo "test">> $FILE && rucio -v upload --rse STFC_STORM --lifetime 3600 --scope testing --register-after-upload $FILE && rucio add-rule --lifetime 3600 testing:$FILE 1 SPSRC_STORM in the storm logs.Have found a token that doesn’t exist in the test.tokens database table. This is because the FTS client does a token exchange, so i’ve set the lifetime of the access token on the admin client to be a day, but when FTS exchanges it it’s presumably using its own access token lifetime (which is set to 3600s; this could be problematic regardless of this issue…).
The token it’s actually using in the request has an issue time of 9:50 today and expiry at 10:50. I think what must be happening here is that FTS is using a cached token which has an expiry date (in its database) set using the token before exchange.
If that’s the case, then mismatches in access token lifetime between the original client and actor client cause a bug, and it’s not possible to give the transfers an access token > 3600s unless we explicitly set it in the FTS client. Email fired to Mihai to confirm this / beg to increase the access token lifetime of the FTS client.
Email to Mihai:
I have been looking at some of our recently failed transfers, e.g.
https://fts3-pilot.cern.ch:8449/fts3/ftsmon/#/job/96afc850-9abc-11ed-88cd-fa163ec64cc5 and it
seems that they the data is being transferring successfully but the token (with a lifetime of 3600s)
is expiring by the time it comes to calculating the destination checksum, so FTS can’t access the
destination storage and the transfer is subsequently marked as failed.
To counter this, I thought I could just increase the access token lifetime of the client that presents
the token to FTS to do the transfer (at this point I had forgotten that FTS does a token exchange), so
I set this to 1 day i.e. 86400s. Now what I’m seeing is that FTS is consistently using an expired token
when attempting to access storage,
e.g. https://fts3-pilot.cern.ch:8449/fts3/ftsmon/#/job/f3285e84-9b2b-11ed-8736-fa163ec6a1a1 to do the
source checksum.
So, in trying to understand this, my questions are these: does FTS cache tokens in a database with an
expiry date? If so, is it possible that FTS is storing the expiry date of the token from the request
(in the case above == 86400s) rather than the access token lifetime following token-exchange? I think
this would result in it thinking it had valid token when selecting the token from the cache, but after
token-exchange it wouldn’t be.
It’s a bit of a wild guess, but it would explain the behaviour I’m now seeing. All the tokens cached by
Rucio are valid for this transaction but inspecting the token presented to storage by FTS I can see it’s
trying to use a token from 9:50am today (coincidentally when I changed the access token lifetime) with a lifetime
of one hour.
The last question I have is…. Can you increase the access token lifetime of the FTS client in ESCAPE?
Two hours would be sufficient for the transfers i’m attempting.Permissions issue resolved. sdc3a Rucio directory wasn't owned by StoRM user (I guess?)
Events have stopped at ~5pm. Still 1215 STUCK rules. These are handled by judge-repairer, so checked pod logs. Looks like it crashed at 7pm. Did a describe::
Last State: Terminated
Reason: OOMKilled
Exit Code: 137
Started: Fri, 20 Jan 2023 01:16:08 +0000
Finished: Fri, 20 Jan 2023 19:00:15 +0000Log with --previous flag:
2023-01-20 17:40:35,309 root 1 INFO judge-repairer[ab5e985:0/1]: Repairing rule 6a52a7b156be4deba039f656a1ea80ea
2023-01-20 17:40:35,341 root 1 DEBUG Resetting counters for rule 6a52a7b156be4deba039f656a1ea80ea [71766/0/1215]
2023-01-20 17:40:36,408 root 1 DEBUG Finished resetting counters for rule 6a52a7b156be4deba039f656a1ea80ea [71766/0/1215]i.e. it broke due to this sdc3a rule. Looks like another lengthy database query. We know it reaches https://github.com/rucio/rucio/blob/53349dab201cdd2d2b309e373b65e25079193785/lib/rucio/core/rule.py#L1033 from the pod logging, but not sure which function is causing it from here. Creates query along the lines of:
SELECT test.contents.child_scope AS test_contents_child_scope, test.contents.child_name AS test_contents_child_name, test.locks.scope AS test_locks_scope, test.locks.name AS test_locks_name, test.locks.rule_id AS test_locks_rule_id, test.locks.rse_id AS test_locks_rse_id, test.locks.account AS test_locks_account, test.locks.bytes AS test_locks_bytes, test.locks.state AS test_locks_state, test.locks.repair_cnt AS test_locks_repair_cnt, test.locks.created_at AS test_locks_created_at, test.locks.updated_at AS test_locks_updated_at
FROM test.contents, test.locks
WHERE test.contents.child_scope = test.locks.scope AND test.contents.child_name = test.locks.name AND test.locks.rse_id = '868976b3-67d2-4091-8657-7018ba6ef411'::uuid AND test.contents.scope = 'sdc3a' AND test.contents.name = 'sdc3a.MS.0.ZW2_IFRQ_0436.ms.FLAG_CMD' AND test.locks.state = 'S'
FOR UPDATE OF locks NOWAITWhere the test.contents.name is cycling at the rate of around 1/s through the whole dataset.
Beginning to look like it really wasn’t designed for large nested containers, or our database needs a lot more grunt.
Increasing the memory for the pod over the weekend in case that helps.
Filed issue with Rucio team (https://github.com/rucio/rucio/issues/6049). In the meantime, removed this bit of insert logic for this particular rule. Now processes about 9000 in 30m but will need to update the updated_col_rep when complete.
Maybe hierarchical client should be something like (to avoid nested datasets):
this has the added advantage of being able to easily switch out dids if individual files are changed, but does mean that directory structure is contained within metadata.
Dask chat w/ James + Rohini.
Some issues with SPSRC_STORM (can't PUT into sdc3a directory).
There's a database call in conveyor-poller that is taking a substantial amount of time because the container contains a lot of child datasets:
Tried to make this call bulk, e.g.
child_datasets = rucio.core.did.list_child_datasets(scope=rule.scope, name=rule.name, session=session)
updated_collection_replicas = [{'scope': dataset['scope'], 'name': dataset['name'], 'did_type': DIDType.DATASET, 'rse_id': rse_id} for dataset in child_datasets]
for updated_collection_replicas_chunks in chunks(updated_collection_replicas, 1000):
logger(logging.DEBUG, 'Chunking {} for update of collection replicas'.format(len(updated_collection_replicas_chunks)))
session.bulk_insert_mappings(models.UpdatedCollectionReplica, updated_collection_replicas_chunks)in ln358 of lock.py, but it only reduces the time from ~60s to 30s per DID.
Did a bit of query analysis e.g.
import uuid
import psycopg
import time
import pprint
try:
with psycopg.connect("dbname='rucio' user='rucio' host='10.244.1.116' password='secret'") as conn:
with conn.cursor() as cur:
values = []
n=10000
for i in range(0,n):
values.append("('{}'::uuid, 'test_insert', 'test_name', 'D', '868976b3-67d2-4091-8657-7018ba6ef411'::uuid, '2023-01-19T11:39:47.471874'::timestamp, '2023-01-19T11:39:47.471879'::timestamp)".format(uuid.uuid4()))
st = time.time()
cur.execute("EXPLAIN (ANALYZE ON, BUFFERS ON) INSERT INTO test.updated_col_rep (id, scope, name, did_type, rse_id, created_at, updated_at) VALUES {}".format(','.join(values)))
elapsed = time.time()-st
print(elapsed, elapsed/n)
analyze_fetched = cur.fetchall()
pprint.pprint(analyze_fetched)
except Exception as e:
print(e)
print("I am unable to connect to the database")but nothing came up (index scans etc.), e.g. for 10000 inserts:
[('Insert on updated_col_rep (cost=0.00..125.00 rows=10000 width=640) (actual '
'time=22956.948..22956.950 rows=0 loops=1)',),
(' -> Values Scan on "*VALUES*" (cost=0.00..125.00 rows=10000 width=640) '
'(actual time=0.015..94.641 rows=10000 loops=1)',),
('Planning Time: 153.252 ms',),
('Execution Time: 22965.714 ms',)]Started transfer between STFC_STORM and SPSRC_STORM. Watching this...
Wrote short OIDC guide for Rucio:
Prerequisites are that you must have an instance of Indigo (https://github.com/indigo-iam/iam). You will need elevated permissions to add priveleged grant types.
Then you must proceed through the guide (https://rucio.cern.ch/documentation/installing_server/#server-configuration-for-open-id-connect-authnz), but in short you need to:
- Add two clients to IAM: one with a client_credentials flow representing admin workflows such as syncing users from IAM->Rucio (admin client), and the other with an authorization_code flow representing user authN/Z with the Rucio server (auth client)
- Tell Rucio about IAM. This is done by creating a "idpsecrets.json" file containing client IDs, secrets, registration access tokens etc. and putting it in the required server/daemon containers. This file is then referenced by adding a section to the Rucio configuration file under the [oidc] section in these containers.
- Add the admin client as an OIDC identity to a superuser (typically "root" but doesn't have to be).
- Add the auth client OIDC identities for users. To do this, you can either modify/run a sync script to periodically add users and auth OIDC identities from your IAM instance to Rucio, e.g. the one used for the ESCAPE project which adds new users
(https://github.com/ESCAPE-WP2/Utilities-and-Operations-Scripts/blob/master/iam-rucio-sync/sync_iam_rucio.py) or the one i've written for SKAO which keeps Rucio in sync with IAM (https://gitlab.com/ska-telescope/src/ska-rucio-task-manager/-/blob/main/src/tasks/sync/iam.py). Alternatively, you can add these identities manually.
- Run the oidc-manager daemon.
- Set `oidc_support: True` to any RSEs that you want Rucio to attempt OIDC authentication with.
- Set configuration attributes to conveyor-submitter, conveyor-poller and reaper daemons.Possible to do a quick sanity check of downloaded structure by using the dry-run param of the rucio-download-directory command. This outputs a tree-like diagram to stdout which with a little rejigging can be compared to the original tree command run on the input measurement set that was uploaded.
Given that this returned without difference, and assuming rsync and rucio both uploaded the files correctly (they both have checksum verification), this loosely suggests that both the files are consistent and the directory structure can be recovered.
Fast and dirty rejigging in case we need it again:
with open("out") as f:
contents = f.read()
keywords = ["ANTENNA", "DATA_DESCRIPTION", "FEED", "FIELD", "FLAG_CMD", "HISTORY", "OBSERVATION", "PHASED_ARRAY", "POINTING", "POLARIZATION", "PROCESSOR", "SOURCE", "SPECTRAL_WINDOW", "STATE"]
for i in range(0,901):
needle = "│ └── ZW2_IFRQ_{:04}.ms__root\n".format(i)
contents = contents.replace(needle, "")
for keyword in keywords:
needle="ZW2_IFRQ_{:04}.ms.{}.".format(i, keyword)
contents = contents.replace(needle, "")
needle="ZW2_IFRQ_{:04}.ms.{}".format(i, keyword)
contents = contents.replace(needle, keyword)
needle="ZW2_IFRQ_{:04}.ms.".format(i)
contents = contents.replace(needle, "")
contents = contents.replace("│ ├", "│ ├")
contents = contents.replace("│ └", "│ └")
contents = contents.replace(" └── ZW2_IFRQ_0900.ms__root\n", "")
contents = contents.replace(" ├", " ├")
contents = contents.replace(" └", " └")
with open("new", 'w') as f:
f.write(contents)Checked permissions on file:
-rw-r--r-- 1 rjoshi rjoshi 280 Dec 24 14:56 table.f2
-rw------- 1 rjoshi rjoshi 4521000960 Dec 25 11:45 table.f2_TSM0Seems to be only one with no o+r permission (so Rucio can’t read). Changed permissions to allow this and rerun at 10:45:00:
$ date; rucio-upload-directory -p plan-dump.json.1; dateETA 10:45:00 -> 11:50:00 (25 channels) ~ 1h, i.e. 25ch/h. 135 channels left so ~ 5.5h?
Obviously ran this not backgrounded again, so have set access permissions on _808 channel to cause a failure as above (and dump a plan).
Noticed docker logs not returning anything for the process.. Apparently need to add UNBUFFERED mode to python shebang, i.e.
!/usr/bin/python3 -u
Reversed permissions changes above and restarted:
date; rucio-upload-directory -p plan-dump.json.3; date
Didn’t work. Will just use screen for now, remembering:
screen
screen -r (reattach)
ctrl+a, ctrl+d (detach)Then to daemonise an existing docker process (-it):
ctrl-p, ctrl-q
Uploaded 739 of the 900 channels but bombed out at ~ 21:00.
2023-01-12 21:17:56,968 [root] plan CRITICAL 276 Encountered exception running step 34786: Exception("FATAL - could not get Adler-32 checksum of file /tmp/sdc3_scratch/MS/MS/ZW2_IFRQ_0740.ms/table.f2_TSM0: [Errno 13] Permission denied: '/tmp/sdc3_scratch/MS/MS/ZW2_IFRQ_0740.ms/table.f2_TSM0'",)Tried running again with -p option (using dumped plan file) but same error.
Attempted with full measurement set.
$ date; rucio-upload-directory --lifetime=31536000 --rse STFC_STORM --scope sdc3a -d /tmp/sdc3_scratch/MS/MS/ -n sdc3a.MS.0Start ~ 14:30.
Turns out this was a proxy issue.
Set nginx directive client_body_in_file_only on; and watched file being uploaded to nginx server before being proxied to the storm endpoint. File sizes looked OK at this stage, but can see that on the StoRM machine the full buffered request isn’t sent. Suggests something wrong with the buffering.
Had previously set the nginx directive proxy_buffering to off but this only prevents buffering of the response (rather than streaming it directly to the location). Another directive, proxy_request_buffering prevents streaming of the request body. Set this to off and retried. Seems to work now with one channel ($ date; rucio-upload-directory --lifetime=3600 --rse STFC_STORM --scope hierarchy_tests -d /tmp/sdc3_scratch/MS/MS/ZW2_IFRQ_0900.ms -n sdc3a.MS.110123.0)
12:38:44 -> 12:40:45 (~120s for 8.5G), i.e. would expect 7500G to take ~30h.
Attempting upload of sdc3a data to rucio datalake. Failed due to timeout issue.